home *** CD-ROM | disk | FTP | other *** search
/ Sprite 1984 - 1993 / Sprite 1984 - 1993.iso / src / kernel / rpc / rpcTrace.c < prev    next >
Encoding:
C/C++ Source or Header  |  1992-12-19  |  10.8 KB  |  399 lines
  1. /*
  2.  * rpcTrace.c --
  3.  *
  4.  *    The tracing routines for the Rpc system.  As messages are moved
  5.  *    through the RPC system time-stamped trace records can be taken
  6.  *    to see where the system spends its time.  The circular buffer
  7.  *    of trace records can be dumped to a file or printed to the console.
  8.  *
  9.  * Copyright (C) 1986 Regents of the University of California
  10.  * All rights reserved.
  11.  */
  12.  
  13. #ifndef lint
  14. static char rcsid[] = "$Header: /cdrom/src/kernel/Cvsroot/kernel/rpc/rpcTrace.c,v 9.7 91/12/11 16:30:39 kupfer Exp $ SPRITE (Berkeley)";
  15. #endif /* not lint */
  16.  
  17.  
  18. #include <sprite.h>
  19. #include <stdio.h>
  20. #include <bstring.h>
  21. #include <rpc.h>
  22. #include <rpcInt.h>
  23. #include <rpcTrace.h>
  24. #include <rpcServer.h>
  25. #include <net.h>
  26. #include <status.h>
  27. #include <dbg.h>
  28. #include <fs.h>
  29. #include <timer.h>
  30. #include <string.h>
  31. #include <dump.h>
  32.  
  33. /*
  34.  * The circular buffer of trace records.
  35.  */
  36. Boolean        rpc_Tracing = FALSE;    /* flag to turn on tracing */
  37.  
  38. Trace_Header    rpcTraceHdr;        /* Trace header info */
  39. Trace_Header    *rpcTraceHdrPtr = &rpcTraceHdr;
  40. /*
  41.  * The results of some standard benchmarks are cached so they
  42.  * get printed out with the trace records.
  43.  */
  44. Time rpcDeltaTime;        /* Average time per RPC */
  45. Time rpcEmptyStampTime;        /* The time to take a trace record without
  46.                  * copying the packet header */
  47. Time rpcFullStampTime;        /* The time to take a trace record that
  48.                  * includes copying the packet header */
  49.  
  50. /*
  51.  *----------------------------------------------------------------------
  52.  *
  53.  * Rpc_PrintTrace --
  54.  *
  55.  *    Print out the last few trace records.  Can be called from
  56.  *    the debugger or via the Test_Stat system call or from an L1 
  57.  *    console command.
  58.  *
  59.  * Results:
  60.  *    None.
  61.  *
  62.  * Side effects:
  63.  *    Print out the trace records on the console.
  64.  *
  65.  *----------------------------------------------------------------------
  66.  */
  67. void
  68. Rpc_PrintTrace(clientData)
  69.     ClientData clientData; /* The number (of most recent) records to print */
  70. {
  71. #ifndef CLEAN
  72.     int numRecords = (int)clientData;
  73.     register int i;    /* Index into trace table */
  74.     int stopIndex;    /* copy of rpcTraceIndex */
  75.     Time baseTime, deltaTime;    /* Times for print out */
  76.     Trace_Record *recordPtr;
  77.     RpcHdr    *rpcHdrPtr;
  78.     int c;        /* Used to identify record types in output */
  79.     char flagString[8];    /* Used to format rpc header flags */
  80.     int stringIndex;
  81.     int linesPrinted = 0;
  82.  
  83.     /* 
  84.      * Provide a quick way to turn RPC tracing on.  Otherwise, somebody has 
  85.      * to log in and invoke rpccmd, which can be slow or even impossible if 
  86.      * the load is high enough.
  87.      */
  88.     if (!rpc_Tracing) {
  89.     rpc_Tracing = TRUE;
  90.     printf("RPC tracing has now been enabled.  Please try again.\n");
  91.     return;
  92.     }
  93.  
  94.     rpcTraceHdrPtr->flags |= TRACE_INHIBIT;
  95.     if (numRecords > rpcTraceHdrPtr->numRecords) {
  96.     numRecords = rpcTraceHdrPtr->numRecords;
  97.     }
  98.     /*
  99.      * Start the print numRecords before rpcTraceIndex.
  100.      * We make a copy of rpcTraceIndex in case in gets incremented
  101.      * during our set of print statements.
  102.      */
  103.     i = (rpcTraceHdrPtr->currentRecord + RPC_TRACE_LEN - numRecords)
  104.         % RPC_TRACE_LEN;
  105.     stopIndex = rpcTraceHdrPtr->currentRecord;
  106.  
  107.     printf("\n");
  108. #define PRINT_HEADER() \
  109.     printf("%s%s\n%s%s\n","    ID type  time       srvr   clnt     cmd",\
  110.     "    psize dsize doff #frags delay", \
  111.     "                   flags    hint   chan",\
  112.     "                            fragmask")
  113.  
  114.     baseTime.seconds = 0;
  115.     baseTime.microseconds = 0;
  116.     do {
  117.     if (linesPrinted % DUMP_LINES_PER_SCREEN == 0) {
  118.         PRINT_HEADER();
  119.     }
  120.     recordPtr = &rpcTraceHdrPtr->recordArray[i];
  121.     Time_Subtract(recordPtr->time, baseTime, &deltaTime);
  122.  
  123.     rpcHdrPtr = (RpcHdr *)recordPtr->traceData;
  124.     printf("%6x ", rpcHdrPtr->ID);
  125.  
  126.     switch(recordPtr->event) {
  127.         default:
  128.         printf("{%d}", recordPtr->event);
  129.         break;
  130.         case RPC_INPUT:
  131.         printf("in ");
  132.         break;
  133.         case RPC_ETHER_OUT:
  134.         printf("out");
  135.         break;
  136.         case RPC_OUTPUT:
  137.         printf("out");
  138.         break;
  139.         case RPC_CLIENT_a:        /* Client interrupt time stamps */
  140.         case RPC_CLIENT_b:
  141.         case RPC_CLIENT_c:
  142.         case RPC_CLIENT_d:
  143.         case RPC_CLIENT_e:
  144.         case RPC_CLIENT_f:
  145.         c = recordPtr->event - RPC_CLIENT_a + 'a';
  146.         printf("Ci%c", c);
  147.         break;
  148.         case RPC_CLIENT_A:        /* Client process level time stamps */
  149.         case RPC_CLIENT_B:
  150.         case RPC_CLIENT_C:
  151.         case RPC_CLIENT_D:
  152.         case RPC_CLIENT_E:
  153.         case RPC_CLIENT_F:
  154.         c = recordPtr->event - RPC_CLIENT_A + 'A';
  155.         printf("Cp%c", c);
  156.         break;
  157.         case RPC_SERVER_a:        /* Server interrupt time stamps */
  158.         case RPC_SERVER_b:
  159.         case RPC_SERVER_c:
  160.         case RPC_SERVER_d:
  161.         case RPC_SERVER_e:
  162.         case RPC_SERVER_f:
  163.         c = recordPtr->event - RPC_SERVER_a + 'a';
  164.         printf("Si%c", c);
  165.         break;
  166.         case RPC_SERVER_A:        /* Server process level time stamps */
  167.         case RPC_SERVER_B:
  168.         case RPC_SERVER_C:
  169.         case RPC_SERVER_D:
  170.         case RPC_SERVER_E:
  171.         case RPC_SERVER_F:
  172.         c = recordPtr->event - RPC_SERVER_A + 'A';
  173.         printf("Sp%c", c);
  174.         break;
  175.         case RPC_CLIENT_OUT:
  176.         printf("Cx ");
  177.         break;
  178.         case RPC_SERVER_OUT:
  179.         printf("Sx ");
  180.         break;
  181.     }
  182.  
  183.     printf(" %3d.%04d",
  184.                deltaTime.seconds,
  185.                deltaTime.microseconds / 100);
  186.     baseTime = recordPtr->time;
  187.     switch(rpcHdrPtr->flags & RPC_TYPE) {
  188.         case RPC_REQUEST:
  189.         flagString[0] = 'Q';
  190.         break;
  191.         case RPC_REPLY:
  192.         flagString[0] = 'R';
  193.         break;
  194.         case RPC_NACK:
  195.         flagString[0] = 'N';
  196.         break;
  197.         case RPC_ACK:
  198.         flagString[0] = 'A';
  199.         break;
  200.         default:
  201.         flagString[0] = '-';
  202.     }
  203.     stringIndex = 1;
  204.     if (rpcHdrPtr->flags & RPC_PLSACK) {
  205.         flagString[stringIndex++] = 'p';
  206.     }
  207.     if (rpcHdrPtr->flags & RPC_LASTFRAG) {
  208.         flagString[stringIndex++] = 'f';
  209.     }
  210.     if (rpcHdrPtr->flags & RPC_CLOSE) {
  211.         flagString[stringIndex++] = 'c';
  212.     }
  213.     if (rpcHdrPtr->flags & RPC_ERROR) {
  214.         flagString[stringIndex++] = 'e';
  215.     }
  216.     flagString[stringIndex] = '\0';
  217.     printf(" %2s", flagString);
  218.     printf(" %3d %d %3d %d ",
  219.                rpcHdrPtr->serverID, rpcHdrPtr->serverHint,
  220.                rpcHdrPtr->clientID, rpcHdrPtr->channel);
  221.     if (((rpcHdrPtr->flags & RPC_ERROR) == 0) &&
  222.         rpcHdrPtr->command >= 0 && rpcHdrPtr->command <= RPC_LAST_COMMAND) {
  223.         printf("%-8s", rpcService[rpcHdrPtr->command].name);
  224.     } else {
  225.         printf("%8x", rpcHdrPtr->command);
  226.     }
  227.     printf(" %5d %5d %5d %2d %2x %5d",
  228.                rpcHdrPtr->paramSize,
  229.                rpcHdrPtr->dataSize,
  230.                rpcHdrPtr->dataOffset,
  231.                rpcHdrPtr->numFrags,
  232.                rpcHdrPtr->fragMask,
  233.                rpcHdrPtr->delay);
  234.     printf("\n");
  235.     ++linesPrinted;
  236.  
  237.     i = (i + 1) % RPC_TRACE_LEN;
  238.     } while (i != stopIndex);
  239.     PRINT_HEADER();
  240.     printf("Delta time = %6d.%06d\n", rpcDeltaTime.seconds,
  241.               rpcDeltaTime.microseconds);
  242.     rpcTraceHdrPtr->flags &= ~TRACE_INHIBIT;
  243. #endif /* not CLEAN */
  244. }
  245.  
  246. /*
  247.  *----------------------------------------------------------------------
  248.  *
  249.  * Rpc_DumpTrace --
  250.  *
  251.  *    Dump out trace records to a file.  Can be called from
  252.  *     the debugger or via the Test_Stat system call.
  253.  *
  254.  * Results:
  255.  *    None.
  256.  *
  257.  * Side effects:
  258.  *    Dump out the trace records to the file.
  259.  *
  260.  *----------------------------------------------------------------------
  261.  */
  262. ReturnStatus
  263. Rpc_DumpTrace(firstRec, lastRec, fileName)
  264.     int firstRec;    /* The index of the first record to print.  The
  265.              * numbering is relative to the oldest record with
  266.              * the oldest record = 1 and the newest record =
  267.              * RPC_TRACE_LEN */
  268.     int lastRec;    /* The index of the last record to print. */
  269.     char *fileName;    /* Name of the file to which to write */
  270. {
  271. #ifndef CLEAN
  272.     register int i;        /* Index into trace table */
  273.     int stopIndex;        /* copy of rpcTraceIndex */
  274.     int offset;            /* file offset */
  275.     Fs_Stream *streamPtr;    /* File to write to */
  276.     ReturnStatus status;    /* Return code */
  277.     Rpc_TraceFileHdr rpcFileHdr;/* Trace file header */
  278.     Rpc_Trace    traceRecord;    /* Trace record for output file */
  279.     Trace_Record    *recordPtr;
  280.     int writeLen;
  281.  
  282.     rpcTraceHdrPtr->flags |= TRACE_INHIBIT;
  283.  
  284.     status = Fs_Open(fileName, FS_CREATE|FS_WRITE, FS_FILE, 0666, &streamPtr);
  285.     if (status != SUCCESS) {
  286.     goto exit;
  287.     }
  288.     /*
  289.      * Set up the header.
  290.      */
  291.     rpcFileHdr.version = rpc_NativeVersion;
  292.     rpcFileHdr.numRecords = lastRec - firstRec + 1;
  293.     rpcFileHdr.rpcDeltaTime = rpcDeltaTime;
  294.     rpcFileHdr.emptyStampMicroseconds = rpcEmptyStampTime.microseconds;
  295.     rpcFileHdr.fullStampMicroseconds = rpcFullStampTime.microseconds;
  296.  
  297.     offset = 0;
  298.     writeLen = sizeof(Rpc_TraceFileHdr);
  299.     status = Fs_Write(streamPtr, (Address)&rpcTraceHdr, offset, &writeLen);
  300.     if (status != SUCCESS) {
  301.     (void)Fs_Close(streamPtr);
  302.     goto exit;
  303.     }
  304.     offset += writeLen;
  305.     
  306.     /*
  307.      * rpcTraceIndex points to record #1.  Map from record number to index.
  308.      */
  309.     i = (rpcTraceHdrPtr->currentRecord + firstRec - 1) % RPC_TRACE_LEN;
  310.     stopIndex = (rpcTraceHdrPtr->currentRecord + lastRec) % RPC_TRACE_LEN;
  311.  
  312.     do {
  313.     writeLen = sizeof(Rpc_Trace);
  314.     recordPtr = &rpcTraceHdrPtr->recordArray[i];
  315.     traceRecord.time = recordPtr->time;
  316.     traceRecord.type = recordPtr->event;
  317.     bcopy((Address)recordPtr->traceData, (Address)&traceRecord.rpcHdr,
  318.         sizeof(RpcHdr));
  319.     status = Fs_Write(streamPtr, (Address)&traceRecord,
  320.                      streamPtr->offset, &writeLen);
  321.     if (status != SUCCESS) {
  322.         (void)Fs_Close(streamPtr);
  323.         goto exit;
  324.     }
  325.     i = (i + 1) % RPC_TRACE_LEN;
  326.     } while (i != stopIndex);
  327.  
  328.     (void)Fs_Close(streamPtr);
  329.     status = SUCCESS;
  330. exit:
  331.     rpcTraceHdrPtr->flags &= ~TRACE_INHIBIT;
  332.     return(status);
  333. #endif /* not CLEAN */
  334. }
  335.  
  336. /*
  337.  *----------------------------------------------------------------------
  338.  *
  339.  * Rpc_StampTest --
  340.  *
  341.  *    This does a calibration timing of the RpcTrace routine.
  342.  *    A numer of calls are made to this routine and the time per
  343.  *    call is computed and printed onto the console.
  344.  *
  345.  * Results:
  346.  *    None.
  347.  *
  348.  * Side effects:
  349.  *    None.
  350.  *
  351.  *----------------------------------------------------------------------
  352.  */
  353. void
  354. Rpc_StampTest()
  355. {
  356. #ifndef CLEAN
  357.     int i;
  358.     Timer_Ticks startTime;
  359.     Timer_Ticks endTime;
  360.     Time diff;
  361.     RpcHdr junkRpcHdr;
  362.  
  363. #define NUMTIMES    1000
  364.  
  365. /*   printf("RpcTrace timing:  "); */
  366.     junkRpcHdr.flags = 0;
  367.  
  368.     Timer_GetCurrentTicks(&startTime);
  369.      for (i=0 ; i<NUMTIMES ; i++) {
  370.     RpcTrace((RpcHdr *)NIL, RPC_SERVER_OUT, "empty");
  371.      }
  372.     Timer_GetCurrentTicks(&endTime);
  373.  
  374.     Timer_SubtractTicks(endTime, startTime, &endTime);
  375.     Timer_TicksToTime(endTime, &diff);
  376.     Time_Divide(diff, NUMTIMES, &diff);
  377. /*   printf("empty = %d, ", diff.microseconds); */
  378.     rpcEmptyStampTime = diff;
  379.  
  380.  
  381.     Timer_GetCurrentTicks(&startTime);
  382.      for (i=0 ; i<NUMTIMES ; i++) {
  383.     RpcTrace(&junkRpcHdr, RPC_CLIENT_OUT, "full");
  384.      }
  385.     Timer_GetCurrentTicks(&endTime);
  386.  
  387.     Timer_SubtractTicks(endTime, startTime, &endTime);
  388.     Timer_TicksToTime(endTime, &diff);
  389.     Time_Divide(diff, NUMTIMES, &diff);
  390. /*    printf("full = %d usecs\n", diff.microseconds); */
  391.     rpcFullStampTime = diff;
  392.  
  393.     for (i=0 ; i<4 ; i++) {
  394.     RpcTrace(&junkRpcHdr, RPC_SERVER_OUT, "full");
  395.     RpcTrace((RpcHdr *)NIL, RPC_CLIENT_OUT, "empty");
  396.     }
  397. #endif /* not CLEAN */
  398. }
  399.